@singalsu can you please give this a try and see if it fixes the problem you faced with missing traces with runtime PM enabled?

@ranj063 I just tried this with the sof patch rebuilt tools but now I get empty trace output. I'll check tomorrow with Kai what I've missed.

@ranj063 @kv2019i Correction, I didn't realize that despite the patched trace didn't show the prior content from boot until this moment when start it shows it later!

Now when I had left sof-logger on and started music playback it traced out normally and I saw now the params() output that got dropped previously when started. Also the traces from boot are seen (component new() stuff) is seen when I scroll back the screen.

So, this looks usable to me now and improvement from non-patched version. Though the start of showing the events should be tested with some lower amount of output test case. Maybe pressing volume up/down from alsamixer and see if it activates the trace.

@singalsu thanks for confirming. I think the missing piece is @keyonjie 's work to copy trace starting from host_offset instead of 0 upon resume.

@keyonjie wrote:

before suspend, I have concern about reset sdev->host_offset at file open, we need figure out that.

Ok, I figured out a way to capture the early logs if sof-logger is started after FW has been active. Please see my comments above I wrote today, and the new patch I uploaded today.

* 24th Apr: Updated patchset with simplified code. Reworked to signal EOF only once so that this works with old and new sof-loggers.

New patchset available. This tries to simplify the logic while still keeping the main feature of resyncing position at suspend/resume cycles. A new sof-logger patch was needed (see PR1312).

@plbossart wrote:

Sorry @kv2019i still confused about the expected transitions for the dtrace_eof boolean. this might be a missing set of comments to explain how this might be used.

Eh, sorry, this round was waste of your time, I slipped a bug in the V4 patchset that further obfuscated intended usage of dtrace_eof variable (although functionally still ok and passed my tests). No excuses, should have been more careful.

Even without my mistake, I agree 'dtrace_eof' is still not ideal, too many comments are needed to explain it. I went back and forth with different names and ended up to rename the variable to 'dtrace_draining' in V5 patchset and further iterated the comments (shorter, just focusing on WHY).

This is still a kludge, I agree, but has a lot of practical utility for sof-logger usage, so I'll still update this PR. If you think this has no chance in upstream, then we might consider dropping altogether and wait until we have time to implement a bigger rework (current WA is to disable runtime PM when taking traces).

@kv2019i something is not right with this methodology suggested in this PR. This is what I tried.

1. After boot: ./sof-logger -l sof-apl.ldc -t
2. stop logger and start again -> no output
3. resume DSP with aplay
4. run sof-logger and now I can see the output again.
5. stop logger and start it again - > no output

So everytime I stop the logger and start it again its output is empty. This is likely because you reset the host_offset to 0 in trace_release. I find this behaviour odd though. I think sof-logger should always be able to read the trace irrespective of whether it is opened for the first time after the DSP is suspended or closed & opened again.

Acked on @ranj063, please make sure the PR really works as we expected before we can merge it, the debugfs trace is used to share FW logs for debugging, so the criteria here should be if it really helps for the debugging, we need show the logs as much as possible, resetting the host_offset and clearing the log output at each logger open sounds really bad idea to me.

Ranjani wrote:

1. After boot: ./sof-logger -l sof-apl.ldc -t
2. stop logger and start again -> no output 
3. resume DSP with aplay
4. run sof-logger and now I can see the output again. 
5. stop logger and start it again - > no output

[...]

So everytime I stop the logger and start it again its output is empty. This is likely because
you reset the host_offset to 0 in trace_release. I find this behaviour odd though. I think
sof-logger should always be able to read the trace irrespective of whether it is opened for
the first time after the DSP is suspended or closed & opened again.

@ranj063 and @keyonjie , yes, this is exactly the expected behaviour. I sent an RFC about the change of behaviour to the SOF mailing list in April when I started to work on this:
https://mailman.alsa-project.org/pipermail/sound-open-firmware/2019-April/003277.html

Note you will not lose traces. You'll always get the last (upto 64K) traces FW sent even if you did not have logger running.

So with the patch, the DMA trace works like "dmesg -c" in kernel. You can get logs out reliably, but you can only read them out once. Until we have implemented offset trace (or trace double-buffering), we must reset the host_offset so SW/FW are resycnhronized. Currently you will often get duplicated traces, or not traces at all -> it's very undeterministic now.

@keyonjie wrote:

the debugging, we need show the logs as much as possible, resetting the host_offset and clearing the
log output at each logger open sounds really bad idea to me.

Ack, but this is not done in the patch. We clear offset at close, specifically to allow user-space to read out the traces before we sync on the position.

So with the patch, the DMA trace works like "dmesg -c" in kernel. You can get logs out reliably, but you can only read them out once. Until we have implemented offset trace (or trace double-buffering), we must reset the host_offset so SW/FW are resycnhronized. Currently you will often get duplicated traces, or not traces at all -> it's very undeterministic now.

@kv2019i but this is quite inconvenient if you can only read the trace once after the DSP is suspended. We can live with it for a short while but we need the bigger change to implement trace offset and should be done soon. Users will start complaining about not being able to read the trace the second time around.

@ranj063 wrote:

@kv2019i but this is quite inconvenient if you can only read the trace once after the DSP is suspended. > We can live with it for a short while but we need the bigger change to implement trace offset and
should be done soon. Users will start complaining about not being able to read the trace the second
time around.

But in context of this PR, the question is which is now a bigger problem:

1. getting duplicate or no traces in normal case unless you disable runtime PM, or
2. inability to to read the trace node multiple times

That's the call we need to make for this PR -> @ranj063 @keyonjie @plbossart
I'm arguing (1) is the bigger problem and am requesting merging this.

Longer term, I'll reiterate my stance that the offset patch does not solve all issues. The trace buffer remains a scratch buffer and even with offset support implemented, user-space has no way to discover where the DSP is writing to. So only reliable way to use DMA trace is to run sof-logger all the time and store traces to user-space continuously. Offset support will not fix this.

I'm arguing (1) is the bigger problem and am requesting merging this.

@kv2019i I personally feel we can't deal with either of them. A few months ago I'd have agreed with you and said (1) is the bigger problem but now we've got external folks using SOF and it is not easy to explain to them that the logger can only read once with PM enabled.

@kv2019i I have a simple suggestion. I agree this PR is necessary but its annoying to not be able to read the data the second time around. Can we possibly change the logger application to read and save the data at first read (possibly in a file) and read from there instead?

@ranj063 wrote:

you and said (1) is the bigger problem but now we've got external folks using SOF and it is not easy to > explain to them that the logger can only read once with PM enabled.

But why the expectation of a "trace store"? Can you elaborate the usage model a bit. For debugging, you should be storing traces continuously to a file. If you want to debug an error after something strange happens, you should cp out the files (trace, exception, memory dumps) and analyze offlien (and attach to bug issue). What is the usage where you read the trace may times?

I think the interface should be viewed as a "trace port" with some intermediate buffering, but it's not a trace store and you'll end with issues if you expect it to be a store (might work sometimes, but not reliable).

@ranj063 wrote:

read the data the second time around. Can we possibly change the logger application to read and
save the data at first read (possibly in a file) and read from there instead?

But this is already supported, right. You 'cp /sys/kernel/debug/sof/trace logfile' and run sof-logger with '-i logfile'. Having sof-logger cache data implicitly sounds a complicated. Where to write, how many traces to keep, potential confusion of combining invalid data from state file cache and valid data from a target data, etc, etc. If really, really need, I'd add a carbon-copy option where sof-logger copies the verbatim binary data all the data to a file, in addition to showing out the parsed log.

@ranj063 wrote:

read the data the second time around. Can we possibly change the logger application to read and
save the data at first read (possibly in a file) and read from there instead?

But this is already supported, right. You 'cp /sys/kernel/debug/sof/trace logfile' and run sof-logger with '-i logfile'. Having sof-logger cache data implicitly sounds a complicated. Where to write, how many traces to keep, potential confusion of combining invalid data from state file cache and valid data from a target data, etc, etc. If really, really need, I'd add a carbon-copy option where sof-logger copies the verbatim binary data all the data to a file, in addition to showing out the parsed log.

@kv2019i sorry didnt realize we had the option of reading from a file with the logger. I am OK with it as long we shout out loud and clear that this is a handicap with the logger at the moment.
@keyonjie what do you think?

@keyonjie what do you think?

@keyonjie ping, see above

Sorry @kv2019i didn't have much time to go to details of your commits and explaining, I am seeing DMA trace logs lost issue(sometimes no any DMA trace logs show even the FW is running and theoretically we should get logs e.g. trigger commands, hw_params commands) when doing KWD debugging these days.

Just went through your commits, my understand to it is something like this:

1. snd_sof_init_trace() // reset host_offset, set dtrace_is_enabled, clear dtrace_draining.
2. file->open() // nothing special we do for trace.
3. file->read()
   sof_wait_trace_avail() // if has enough data, return; otherwise, wait for event.
4. file->release() // e.g. Ctrl+c to exit sof-logger.
5. snd_sof_release_trace() // clear dtrace_is_enabled, set dtrace_draining.

Without suspend/resume, the typical flow is 1->2->3->4(first sof-logger run)->2->3->4...->2->3->4 (the Nth sof-logger run), this works fine as dtrace_draining is never set and we do nothing in 4) actually. dtrace_is_enabled is true, dtrace_draining is false, and host_offset is keep aligned with FW position update.

When suspend happens, let's consider about 2 scenarios:

a. suspend without sof-logger run, that is 1->[2->3->4]->5, after 5), dtrace_is_enabled is false, dtrace_draining is true, and host_offset is aligned with the last update from FW position update.

Here, when we run sof-logger, 2->3(read out all logs, and then clear dtrace_draining, works fine here)->4(reset host_offset, that means if we try open sof-logger again, no logs will be showed at the 2nd iteration, this is also fine IMO).

Then 1->[2->3->4] again, everything same with the first boot, we won't get logs that belong to the previous active stage, this also looks legit(so for first boot fail issues e.g. tplg IPC failure, we can run sof-logger before we turn the driver back to resume via any audio commands, to debug those issues).

So in general, this case a is fine for me.

b. suspend with sof-logger run, that is 1->2->3->5, after 5), dtrace_is_enabled is false, dtrace_draining is true, and host_offset is aligned with the last update from FW position update.

Here, the last logs before suspend is already showed, so if
b_1. 4) is run(Ctrl+c) at suspended, we will reset host_offset(No problem, we have already read them).
b_2. go back to 1) with resume(sof-logger keep running), the next trace position update from FW will start from 0(might be >0 actually), then the sof-logger will output staled(or not existed) [host_offset, buffer_size) logs before it is aligned to the new logs data, this is a little bit confused here, but more logs/noise is better than no logs, I can be tolerant to this actually.

So this case b is acceptable to me.

So, after long analyzing and chatter here, I think this is good PR to be merged now, thank you so much.

Thank you @keyonjie for the very detailed response and review. Your analysis is correct. I only have one note for this:

b. suspend with sof-logger run, that is 1->2->3->5, after 5), dtrace_is_enabled is false, dtrace_draining is true, and host_offset is aligned with the last update from FW position update.
[...]
b_2. go back to 1) with resume(sof-logger keep running), the next trace position update from FW will start from 0(might be >0 actually), then the sof-logger will output staled(or not existed) [host_offset, buffer_size) logs before it is aligned to the new logs data, this is a little bit confused here, but more logs/noise is better than no logs, I can be tolerant to this actually.

In fact we can cover this case as well. With recent patches to sof-logger, when you run sof-logger in trace mode (-t) and this b_2 case happens, sof-logger will notice the end of draining phase (read returns once with 0 bytes available) and reopens the trace node. So when FW starts again, sof-logger will continue reading from 0.

If you use an older sof-logger binary, then the result will be as per your analysis above and some stale traces will be output.

So, after long analyzing and chatter here, I think this is good PR to be merged now, thank you so much.

Great, thank you! @plbossart This would seem to be good to go!

b_2. go back to 1) with resume(sof-logger keep running), the next trace position update from FW will start from 0(might be >0 actually), then the sof-logger will output staled(or not existed) [host_offset, buffer_size) logs before it is aligned to the new logs data, this is a little bit confused here, but more logs/noise is better than no logs, I can be tolerant to this actually.

In fact we can cover this case as well. With recent patches to sof-logger, when you run sof-logger in trace mode (-t) and this b_2 case happens, sof-logger will notice the end of draining phase (read returns once with 0 bytes available) and reopens the trace node. So when FW starts again, sof-logger will

Great to know about this, thanks.

continue reading from 0.

Thanks @keyonjie let's merge and test